PHP Segmentation fault 问题排查笔记
1.问题征兆
国庆前收到报警通知 , 线上数据同步脚本容器容量使用超过200G,并以很快的速度增加,查看线上监控,每隔10分钟阶梯性增长数百MB,一天平均增加20G左右
1 | 【报警集群】prod集群【报错信息】Pod website-newstagger-cron-789668bc64-85qgw的容器website-newstagger-cron-pod容量使用超过了200G(当前值221.97G) [Level1 critical] |
2.初步排查
由于线上项目已经发布将近一个月,且期间除了已知的一些问题邮件报警外并没有发现其他问题,业务方使用也很正常,因此最开始判读是线上日志积累的太多,但是联系运维删除运行日志后,发现容量仅减少了几个G,由于线上容器没有直接操作权限,开始在测试环境排查
查看测试环境容器监控后,发现测试环境容量虽然没有用到200G,但也有80多G,使用du命令查找后发现容量全部在root目录下
1 | 用到的du命令 |
进入root目录后,执行ls 发现root目录下有大量的 core.数字
如core.885
, 文件大小只有100兆左右的和20兆左右的,就是这些文件占用的99%的存储空间.此时我并不知道这个文件是因为什么产生,也不知道core文件是什么,直接执行cat 选择一个比较小的查看后,满屏的乱码刷了几十秒,期间夹杂着一些中文似乎是某个接口的返回值,然后我就去找搜索引擎请教core文件是什么了。
很快我找到一篇文章
Core文件其实就是内存的映像,当程序崩溃时,存储内存的相应信息,主用用于对程序进行调试。当程序崩溃时便会产生core文件,其实准确的应该说是core dump 文件,默认生成位置与可执行程序位于同一目录下,文件名为
core.***
,其中***
是某一数字。
初步查看了一下 ,目测离找到问题根源还比较遥远,由于手头任务还比较多,且马上就要为祖国母亲庆生,这种激动人心的时刻,怎么能静下心查bug呢?再加上项目已经稳定运行了20多天 ,戒指这个问题除了占用内存外应该不会产生什么大的影响,在测试环境执行删除命令后,容量回复正常,不到1G,然后我联系了运维删除了线上容器的的core文件,很幸运的是我平安的度过了祖国母亲的生日
1 | # 删除文件命令 |
3.复现问题
国庆回来后仅过了一天,熟悉的报警再次来临
1 | 【报警集群】prod集群【报错信息】Pod website-newstagger-cron-789668bc64-85qgw的容器website-newstagger-cron-pod容量使用超过了200G(当前值200.32G) [Level1 critical] |
是时候找到真正的原因了,首先需要让问题复现。
在之前的那篇文章中,我已经了解到gdb命令可以用来分析core dump文件,再次请教搜索引擎,初步学习下gdb
的用法
1 | gdb [exec file] [core file] |
然后执行:
1 | gdb php core.885 |
在很多的信息中我注意到了这些
1 | Reading symbols from /lib64/libdb-4.7.so...(no debugging symbols found)...done. |
程序似乎是在执行db相关操作的时候崩溃的,再使用gdb bt
命令 ,发现程序时在访问0x7ffcc258de10
地址时出错了,又用同样的方法分析了几个其他的core dump 文件 错误都是一样的,同时我还有新的发现:
测试环境的core dump文件只有两个大小,109MB和19MB,同样大小的文件中文的部分也是一致的
简单介绍下我的程序的逻辑:
首先通过corntab
每分钟启动一个manager
进程, manager
进程会判断数据库中有多少条问句需要更新,然后启动一批thread
进程去请求问句接口来更新该问句的结果,每条问句会有几十到几百上千条不同的信息,这些信息需要关联到不同的 标的 并写入到数据库中
程序的每个问句的结果是不一样的,从core dump 文件的分析结果来看 ,应该是其中两条问句的进程在执行过程中出现了问题,同时根据前面Loaded symbols for /lib64/libdb-4.7.so
,可以推测是在请求数据库的时候出现了异常,找到这两个结果对应的问句后,单独执行这两个问句的进程,问题复现了
4. 追根溯源
复现问题后,通过简单的断点测试后,我定位到了业务代码中程序奔溃的地方
1 | /** |
进程是在执行$this->getAdapter()->query($sql)
时崩溃的,之后的代码就是zend framework的部分了,首先检查此时生成的SQL语句,将它保存到文本中查看,文件很长,即使只保存一条数据也有27K的大小,凭借肉眼去判断SQL太难了,因此直接使用mysql命令执行保存的SQL 文件,出乎意料的sql执行成功了~
insertAll 依赖代码如下:
1 |
|
下面只能继续向框架层去挖掘了 , 首先进入query
方法
1 | /** |
经过断点测试,在执行到$stmt = $this->prepare($sql);
时进程崩溃,查看prepare()
方法:
通过IDE的代码跳转,我跳转到了这里,然后IDE就不能继续跳转了
1 | abstract public fucntion prepare($sql); |
经过观察后,发现这个目录同级还有一些Mysqli.php , Oracle.php
文件,进入Mysqli.php
后,果然找到了prepare
方法
1 | /** |
通过打印$stmtClass
我得到了下一个目标Zend_Db_Statement
,它的构造函数如下
1 | /** |
同样的断点测试,定位到了$this->_parseParameters($sql);
_parseParameters
方法如下:
1 | /** |
这次很快我们就定位到了第一行的$sql = $this->_stripQuoted($sql);
1 | /** |
这次,我们终于要接近问题的真相了,程序在执行到$sql = preg_replace("/\"(\\\\\"|[^\"])*\"/Us", '', $sql);
时崩溃,而preg_replace
是一个php 的系统函数
我将前面保存的sql语句直接传入
再次请教搜索引擎,preg_replace Segmentation fault
我得到了以下地址:
https://stackoverflow.com/questions/20750757/php-segmentation-fault-during-preg-replace
https://bugs.php.net/bug.php?id=61579
和我的遭遇类似,这是一个由于低效正则在替换长文本是由于超过最大递归深度引发的内存溢出问题,属于PHP5.6版本中底层源码的bug
之后我一度陷入僵局,问题已经定位到,不过如果替换掉框架内的这行代码,鬼知道会不会引发什么其他的问题,升级php版本的工作量也不少,有什么简单的方法可以解决吗?
幸运的是,同事给了我一份他曾经写过的insertAll
方法的源码,通过的它的方法,并没有触发这个bug,经过分析,我发现他的代码中没有对特殊字符进行转义,只是使用单引号将值包了起来,而我使用了addslashes
这个函数进行了转义,由于要写入数据库的是请求接口结果的json
数据,因此转义时产生了大量的\"
, 而这极大的影响了 preg_replace 的效率 因此,我手工实现了一个转义函数,通过字符实体替换反斜杠转义,成功规避问题
1 | public fucntion stringEscape($value){ |